﻿using System.Diagnostics;
using System.Text;
using System.Web.Mvc;
using log4net;

namespace Pyramid.Common
{
	public class LoggingFilterAttribute : ActionFilterAttribute
	{
		#region Logging

		private const string StopwatchKey = "DebugLoggingStopWatch";

		private static readonly ILog Log = LogManager.GetLogger("AdoNetLogger");

		#endregion

		public override void OnActionExecuting(ActionExecutingContext filterContext)
		{
			if (!Log.IsDebugEnabled) return;
			var loggingWatch = Stopwatch.StartNew();
			filterContext.HttpContext.Items.Add(StopwatchKey, loggingWatch);

			var message = new StringBuilder();
			message.Append(string.Format("Executing controller {0}, action {1}",
			                             filterContext.ActionDescriptor.ControllerDescriptor.ControllerName,
			                             filterContext.ActionDescriptor.ActionName));

			Log.Debug(message);
		}

		public override void OnActionExecuted(ActionExecutedContext filterContext)
		{
			if (!Log.IsDebugEnabled) return;
			if (filterContext.HttpContext.Items[StopwatchKey] == null) return;
			var loggingWatch = (Stopwatch) filterContext.HttpContext.Items[StopwatchKey];
			loggingWatch.Stop();
			var timeSpent = loggingWatch.ElapsedMilliseconds;
			var message = new StringBuilder();
			message.Append(string.Format("Finished executing controller {0}, action {1} - time spent {2}",
			                             filterContext.ActionDescriptor.ControllerDescriptor.ControllerName,
			                             filterContext.ActionDescriptor.ActionName,
			                             timeSpent));

			Log.Debug(message);
			filterContext.HttpContext.Items.Remove(StopwatchKey);
		}
	}
}